Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Diagnostics Middleware API review #4604

Closed

Conversation

Tratcher
Copy link
Member

@Tratcher Tratcher commented Oct 23, 2023

Martin asked to review all of the experimental content here before RTM.

Microsoft Reviewers: Open in CodeFlow

@Tratcher Tratcher added this to the 8.0-rtm milestone Oct 23, 2023
@Tratcher Tratcher self-assigned this Oct 23, 2023

namespace Microsoft.AspNetCore.Diagnostics.Logging;

[Experimental("EXTEXP0013", UrlFormat = "https://aka.ms/dotnet-extensions-warnings/{0}")]
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Experimental


namespace Microsoft.AspNetCore.Diagnostics.Logging;

[Experimental("EXTEXP0013", UrlFormat = "https://aka.ms/dotnet-extensions-warnings/{0}")]
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Experimental

public class RequestHeadersLogEnricherOptions
{
[Required]
[Experimental("EXTEXP0003", UrlFormat = "https://aka.ms/dotnet-extensions-warnings/{0}")]
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Experimental


namespace Microsoft.Extensions.DependencyInjection;

[Experimental("EXTEXP0013", UrlFormat = "https://aka.ms/dotnet-extensions-warnings/{0}")]
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Experimental

@joperezr
Copy link
Member

I'm not sure I'm following, is this API that already exists in the library and the purpose of this is to do a snapshot review of it? Or is this new API that will be added?

@Tratcher
Copy link
Member Author

This is for review of the current APIs so they can graduate from Experimental.

@geeknoid geeknoid marked this pull request as draft October 23, 2023 23:19
@geeknoid
Copy link
Member

@joperezr This is to review experimental APIs that are currently present in the code base, with the goal of graduating the APIs to be approved and so we can remove the experimental attribute.

@joperezr
Copy link
Member

@joperezr This is to review experimental APIs that are currently present in the code base, with the goal of graduating the APIs to be approved and so we can remove the experimental attribute.

Would it make sense to hold off on changing anything from Experimental -> stable for 8.0 given how close we are to the snap and instead postpone that for 8.1? Ongoing work around documentation, testing, and dogfooding is happening so I think it would make sense to have the least amount of moving pieces as possible. After snapping by the end of this week, we should be able to make these changes next week on the branch that will have 8.1 changes (which as we agreed last week would be main)

@davidfowl
Copy link
Member

Looking at some of these bits, have we done the telemetry pass on these assemblies yet? I'm asking specifically about dimension names, tag names (distributed tracing), logging levels (how much gets logged by default and in what category).

@Tratcher
Copy link
Member Author

@davidfowl yes (?) https://github.com/dotnet/r9-planning-private/issues/124.

The http logging components no longer directly log, they delegate to AspNetCore's http logging middleware. They only default they add is the Duration field.

return services.AddHttpLogging(o =>
{
o.CombineLogs = true;
o.LoggingFields |= HttpLoggingFields.Duration;
})

The latency middleware doesn't directly emit logs or telemetry, it passes that off to the abstractions in Microsoft.Extensions.Telemetry.Abstractions. Not sure where they send it.

@davidfowl
Copy link
Member

The http logging components no longer directly log, they delegate to AspNetCore's http logging middleware. They only default they add is the Duration field.

Ok great! I assume the same goes for metrics and distributed traces?

The latency middleware doesn't directly emit logs or telemetry, it passes that off to the abstractions in Microsoft.Extensions.Telemetry.Abstractions. Not sure where they send it.

Same questions as above. Logs, metrics and traces and and whatever enrichment we do.

@Tratcher
Copy link
Member Author

For this package at least, yes.

@joperezr joperezr added the * NO MERGE * Do not merge this PR as long as this label is present. label Oct 30, 2023
@xakep139
Copy link
Contributor

@davidfowl there's no HTTP tracing/metering in extensions repo as we had to remove these bits.
There are only three components that emit metrics:

  • ResourceMonitoring
  • HealthChecks
  • HeaderParsing

All metrics are listed in #4482 (comment)

@davidfowl
Copy link
Member

@xakep139 What about logs and various log levels and categories?

Also trace enrichment? Did we remove any activity enrichment as well?

@joperezr
Copy link
Member

@xakep139 What about logs and various log levels and categories?

I believe all of that was done here: #4545

@iliar-turdushev
Copy link
Contributor

iliar-turdushev commented Nov 1, 2023

@xakep139 What about logs and various log levels and categories?

I believe all of that was done here: #4545

@joperezr I checked only log categories when I was working on #4545, and I didn't know that I had to check log levels. How can we ensure that log levels we use are correct/good?

@xakep139
Copy link
Contributor

xakep139 commented Nov 1, 2023

@xakep139 What about logs and various log levels and categories?

Also trace enrichment? Did we remove any activity enrichment as well?

Correct, all tracing (including enrichment) bits were removed.

@davidfowl
Copy link
Member

@joperezr I checked only log categories when I was working on #4545, and I didn't know that I had to check log levels. How can we ensure that log levels we use are correct/good?

This is a bit of an art. I don't know that we have anything written up on best practices here, do we @noahfalk. I will say that there's a tendency to "over log" everything as information by default. The user is going to see everything >= information by default (this is why ASP.NET Core defaults to "Warning" in the template). It results in "logging spam" (and we get feedback from customers about how noisy it is).

I would recommend:

  • Having log categories that developers can control (we don't have per log control, just the category)
  • Reducing the number of informational logs (these will show up per request)
  • Checking the log level for the category before logging, especially if data is being transformed

Anything else @noahfalk ?


namespace Microsoft.AspNetCore.Diagnostics.Latency;

public static class RequestCheckpointConstants
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think these static classes declaring telemetry constants need to be public. I don't understand what the use-case would be. For anyone who wanted to parse the ILogger data after it was emitted or make their own implementation that emits the same values I expect they would just write these same constants into their own code rather than take a ref on this assembly.


namespace Microsoft.AspNetCore.Diagnostics.Logging;

public static class HttpLoggingTagNames
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Same as above, I don't think this needs to be public.

@noahfalk
Copy link
Member

noahfalk commented Nov 2, 2023

This is a bit of an art. I don't know that we have anything written up on best practices here, do we @noahfalk.

I don't think we have any written guidance specific to what log level is most appropriate for a given log message. I agree with your impression that we have historically made informational logging too verbose.
My current mental model would be something like this:

  • If a high scale service (a realistic one, not a contrived benchmark) is likely to hit the log statement more than 1000 times/sec then consider it expensive. More than 100K times/sec consider it really expensive.
  • Really expensive logs should be Debug or Trace level
  • It is OK to have a single expensive log marked informational in a category, as long as the data is high value. Instead of adding a second one you could either combine both into a single log, mark one of them with a higher verbosity, or move them into different sub-categories so they can be filtered independently.

@iliar-turdushev
Copy link
Contributor

iliar-turdushev commented Nov 2, 2023

  • Really expensive logs should be Debug or Trace level

What if a really expensive log logs exception/error information? For example, the following message is logged when an enricher fails to enrich an incoming HTTP request.

[LoggerMessage(0, LogLevel.Warning, "Enricher failed: {Enricher}.")]

It could become really expensive if some enricher starts to fail for each HTTP request. Should we change the level of the log message to Debug in this case?

@noahfalk
Copy link
Member

noahfalk commented Nov 2, 2023

It could become really expensive if some enricher starts to fail for each HTTP request. Should we change the state of the log message to Debug in this case?

I'd consider the 'likely' behavior as the typical, presumably healthy, steady-state app behavior. If having enrichment fail on every request was a typical and ignorable result then Debug might be a good idea, but I'm guessing for this example service owners wouldn't consider that a typical or healthy state. Given the choice between logging getting verbose temporarily in response to the error condition or not seeing anything because the message was marked as Debug, I suspect they'd prefer the verbose logs.

I'd also guess service owners would appreciate some kind of rate limiting to avoid getting spammed with 100K/sec of the same error. That feels like something we would enable as part of overall logging pipeline infrastructure and not request every place in code that can generate an error do its own custom rate limiting implementation or to be really conservative with its verbosity level.

@iliar-turdushev
Copy link
Contributor

I'd consider the 'likely' behavior as the typical

@noahfalk Thank you very much for guidance. I've created a PR to review existing log messages and their log levels. Could you, please, take a look? #4652 In general, our current log levels are good.

cc @davidfowl

@Tratcher Tratcher removed their assignment Nov 2, 2023
@ghost ghost assigned Tratcher Nov 2, 2023
@Tratcher Tratcher assigned geeknoid and unassigned Tratcher Nov 2, 2023
@ghost ghost assigned Tratcher Nov 2, 2023
@joperezr
Copy link
Member

Closing as I believe this is stale now.

@joperezr joperezr closed this Jan 22, 2024
@github-actions github-actions bot locked and limited conversation to collaborators Feb 22, 2024
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
* NO MERGE * Do not merge this PR as long as this label is present.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

7 participants